home *** CD-ROM | disk | FTP | other *** search
/ Celestin Apprentice 5 / Apprentice-Release5.iso / Source Code / Libraries / Sherlock 2.0 / Sherlock_DevLib / sl_dump.c next >
Text File  |  1996-04-06  |  14KB  |  673 lines
  1. /*
  2.     Sherlock reporting routines.
  3.  
  4.     source:  sl_dump.c
  5.     started: November 4, 1993.
  6.     version: February 5, 1996.
  7.         November 7, 1995.
  8.             Call l2s instead of sprintf.
  9.         September 26, 1995.
  10.             Bug fix to sl_dump_start.
  11.             Several minor formatting changes.
  12.         December 26, 1993.
  13.             Installed variable width columns in dumps.
  14. */
  15. #include <LIBlib.h>
  16.  
  17. #include <sl.h>
  18. #include <sl2.h>
  19.  
  20. #include <stdlib.h>
  21. #include <string.h>
  22.  
  23. #undef USE_TOTAL_TIME
  24.  
  25. /*
  26.     Define the default widths of the various columns.
  27.     These widths are actually recomputed in sl_dump_start.
  28. */
  29. long TRACEPOINT_WIDTH = 18;
  30. long CALL_WIDTH = 15;
  31. long OWN_WIDTH = 17;
  32. long INNER_WIDTH = 17;
  33. long ENABLED_WIDTH = 10;
  34.  
  35. /*
  36.     The fudge factor is an additional "by hand" adjustment.
  37.     It is used to compensate for the fact that the Sherlock timing macros
  38.     cut off the ticks as soon possible, but that understates the Sherlock
  39.     overhead, especially for often-called routines.
  40. */
  41.  
  42. /* Define global variables. */
  43. bool sl_use_adjust_flag = TRUE;
  44.  
  45. /* Define local variables. */
  46.  
  47. static double sl_adjval;        /* Time fudge factor. */
  48.  
  49. static long tot_times;            /* Raw statistics. */
  50. static long tot_2times;
  51. static long tot_calls;
  52. static long tot_ttimes;
  53.  
  54. static long totp_calls;            /* Percentages corresponding to raw statistics. */
  55. static long totp_times;
  56. static long totp_2times;
  57. static long totp_ttimes;
  58.  
  59. static long subtot_calls;        /* Subtotals. */
  60. static long subtotp_calls;
  61. static long subtot_times;
  62. static long subtotp_times;
  63. static long subtot_2times;
  64. static long subtotp_2times;
  65.  
  66. static long runtot_calls;        /* Running totals used to print grand totals. */
  67. static long runtot_times;
  68. static long runtot_2times;
  69.  
  70. static    sl_node a_list;            /* Head of alphabetical list of nodes. */
  71.  
  72. /*
  73.     Function prototypes for internal routines.
  74. */
  75. static unsigned long
  76.     sl_adjust (sl_node * np, long val);
  77. static void
  78.     sl_dump_col (int width, long n1, long n2, long n3,char * delim, int msec_flag);
  79. static short
  80.     l2s (char * buf, long val);
  81.  
  82. /*
  83.     This routine defines the meaning of the sl_adjval constant.
  84.  
  85.     return val - (long) (p->calls * sl_adjval).
  86. */
  87. static unsigned long
  88. sl_adjust(sl_node * np, long val)
  89. {
  90.     double dval;
  91.     register long rval;
  92.     static bool adj_flag = FALSE;
  93.  
  94.     if (sl_use_adjust_flag) {
  95.  
  96.         /* 2/18/93: Set sl_adjval on the fly. */
  97.         if (adj_flag == FALSE) {
  98.             sl_setadj();
  99.             adj_flag = TRUE;
  100.         }
  101.  
  102.         dval = (double) (np -> calls);
  103.         dval = dval * sl_adjval;
  104.         rval  = val - (long) dval;
  105.         if (rval < 0) {
  106.             rval = 0;
  107.         }
  108.         return rval;
  109.     }
  110.     else {
  111.         return val;
  112.     }
  113. }
  114.  
  115. /*
  116.     SL_DUMP macro--Print all statistics.
  117. */
  118.  
  119. void
  120. sl_dump(void)
  121. {
  122.     sl_dump_start();
  123.     sl_dump_header(SL_DUMP_ALL_STATS);
  124.     sl_dump_names(SL_DUMP_ALL_STATS, NULL);
  125.     sl_dump_totals();
  126.     sl_dump_wild();
  127. }
  128.  
  129. /*
  130.     Dump only enabled entries.
  131. */
  132.  
  133. void
  134. sl_edump(void)
  135. {
  136.     sl_dump_start();
  137.     sl_dump_header(SL_DUMP_ENABLED_STATS);
  138.     sl_dump_names(SL_DUMP_ENABLED_STATS, NULL);
  139.     sl_dump_totals();
  140. }
  141.  
  142. /*
  143.     Print one column of statistics.
  144. */
  145. static void
  146. sl_dump_col(
  147.     int width, long n1, long n2, long n3,
  148.     char * delim, int msec_flag)
  149. {
  150.     char buf [CVT_BUF_SIZE];
  151.  
  152.     if (n1 < 0) n1 = 0;
  153.     if (n2 < 0) n2 = 0;
  154.     if (n3 < 0) n3 = 0;
  155.  
  156.     if (msec_flag) {
  157.         epadmsec(n1, width);
  158.     }
  159.     else {
  160.         epadlong(n1, width);
  161.     }
  162.     es(" ");
  163.     es(delim);
  164.     epads(cvt_percent(buf, CVT_BUF_SIZE, n2, n3) , 5);
  165.     es("%");
  166. }
  167.  
  168. /*
  169.     Print the header used by sl_dump and sl_edump.
  170. */
  171. void
  172. sl_dump_header(bool dump_all_flag)
  173. {
  174.     ecnls(2);
  175.     es(dump_all_flag ? "All " : "Enabled ");
  176.     es("Sherlock statistics.  (Times in msec.)\n");
  177.     ecnls(2);
  178.  
  179.     epads("tracepoints",    TRACEPOINT_WIDTH);
  180.     epads("calls",            CALL_WIDTH+8);
  181.     epads("own time",        OWN_WIDTH+8);
  182.     epads("inner time",        INNER_WIDTH+8);
  183.     epads("enabled", ENABLED_WIDTH);
  184.     enl(); enl();
  185. }
  186.  
  187. /*
  188.     Dump the statistics for one name.
  189.  
  190.     Do *not* initialize the statistic here.
  191. */
  192. void
  193. sl_dump_name(char * name)
  194. {
  195.     sl_dump_names(FALSE, name);
  196. }
  197.  
  198. /*
  199.     Dump all the names with interesting statistics.
  200.     If name is specified, dump only that name.
  201. */
  202. void
  203. sl_dump_names(bool dump_all_flag, char * dump_name)
  204. {
  205.     register sl_node    * p;
  206.  
  207.     for (p = a_list.alpha; p; p = p -> alpha) {
  208.         if (
  209.             (dump_name != NULL && strcmp(p -> name, dump_name)==0) ||
  210.             (
  211.                 dump_name == NULL && dump_all_flag &&
  212.                 (p -> calls || p -> time || p -> time2)
  213.             )
  214.         ) {
  215.  
  216.             /* Print breakpoint name. */    
  217.             epads(p -> name, TRACEPOINT_WIDTH);
  218.  
  219.             sl_dump_col(CALL_WIDTH, p -> calls, p -> calls,
  220.                 tot_calls, "=", FALSE);
  221.  
  222.             runtot_calls += p -> calls;
  223.             subtot_calls += p -> calls;
  224.  
  225.             totp_calls    += cvt_1000percent(p -> calls, tot_calls);
  226.             subtotp_calls += cvt_1000percent(p -> calls, tot_calls);
  227.             {
  228.                 long n = sl_adjust(p, p -> time);
  229.                 sl_dump_col(OWN_WIDTH, n, n, tot_times, "=", TRUE);
  230.             }
  231.             {
  232.                 long n = sl_adjust(p, p -> time);
  233.                 runtot_times += n;
  234.                 subtot_times += n;
  235.             }
  236.             {
  237.                 long n = cvt_1000percent(sl_adjust(p, p -> time), tot_times);
  238.                 totp_times += n;
  239.                 subtotp_times += n;
  240.             }
  241.             {
  242.                 long n = sl_adjust(p, p -> time2);
  243.                 sl_dump_col(INNER_WIDTH, n, n, tot_2times, "=", TRUE);
  244.             }
  245.             {
  246.                 long n = sl_adjust(p, p -> time2);
  247.                 runtot_2times += n;
  248.                 subtot_2times += n;
  249.             }
  250.             {
  251.                 long n = cvt_1000percent(sl_adjust(p, p -> time2), tot_2times);
  252.                 totp_2times += n;
  253.                 subtotp_2times += n;
  254.             }
  255.  
  256.             /* Indicate whether tracing was enabled. */
  257.             if (dump_all_flag || dump_name != NULL) {
  258.                 epadbool(p -> trace, ENABLED_WIDTH);
  259.             }
  260.             enl();
  261.         }
  262.     }
  263. }
  264.  
  265. void
  266. sl_dump_start(void)
  267. {
  268.     register sl_node    * p;
  269.     register char    * pname;
  270.     register sl_node    * q;
  271.     register sl_node * q1;
  272.     register int        i;
  273.     char buf [CVT_BUF_SIZE];
  274.  
  275.     /* Be very careful. */
  276.     if (sl_htab == NULL) {
  277.         return;
  278.     }
  279.  
  280.     /*
  281.         Initialize alpabetical list.
  282.     */
  283.     a_list.alpha = NULL;
  284.     a_list.next  = NULL;
  285.     a_list.name  = NULL;
  286.  
  287.     /* Calculate grand total times. */
  288.     tot_calls = 0;
  289.     tot_times = 0;
  290.     tot_2times = 0;
  291.     tot_ttimes = 0;
  292.  
  293.     totp_calls = 0;
  294.     totp_times = 0;
  295.     totp_2times = 0;
  296.     totp_ttimes = 0;
  297.  
  298.     runtot_calls = 0;
  299.     runtot_times = 0;
  300.     runtot_2times = 0;
  301.  
  302.     /*
  303.         Bug fix: 9/26/95: make sure the columns are wide enough for their headings.
  304.         This code is ugly because it depends on sl_dump_col.
  305.     */
  306.     ENABLED_WIDTH        = 2 + strlen("enabled");
  307.     TRACEPOINT_WIDTH    = 2 + strlen("tracepoints");
  308.     CALL_WIDTH            = 4;
  309.     OWN_WIDTH            = 4;
  310.     INNER_WIDTH            = 4;
  311.  
  312.     /* Scan all buckets. */
  313.     for (i = 0; i < SL_MAX_HASH; i++) {
  314.  
  315.         for (p = sl_htab[i]; p; p = p -> next) {
  316.  
  317.             tot_calls  += p -> calls;
  318.             tot_times  += sl_adjust(p, p -> time);
  319.             tot_2times += sl_adjust(p, p -> time2);
  320.  
  321.             /*
  322.                 Sort the entries that will be printed by creating
  323.                 a list in the alpha field of the nodes.
  324.             */
  325.             if (p -> calls || p -> time || p -> time2) {
  326.                 pname = p -> name;
  327.                 TRACEPOINT_WIDTH = max(TRACEPOINT_WIDTH, strlen(p -> name));
  328.                 for (q1 = &a_list, q = q1 -> alpha;
  329.                     ;
  330.                      q1 = q, q = q -> alpha
  331.                     ) {
  332.  
  333.                     if (q == NULL ||
  334.                         strcmp(pname, q -> name) < 0
  335.                        ) {
  336.                         q1 -> alpha = p;
  337.                         p  -> alpha = q;
  338.                         break;
  339.                     }
  340.                 }
  341.             }
  342.         }
  343.     }
  344.  
  345.     tot_ttimes = tot_times + tot_2times;
  346.     
  347.     #if 0 /* Don't call sprintf */
  348.  
  349.         CALL_WIDTH    = max(CALL_WIDTH,    1 + sprintf(buf, "%ld", tot_calls));
  350.         OWN_WIDTH    = max(OWN_WIDTH,    1 + sprintf(buf, "%ld", ticks2msec(tot_times)));
  351.         INNER_WIDTH    = max(INNER_WIDTH,    1 + sprintf(buf, "%ld", ticks2msec(tot_2times)));
  352.     
  353.     #else
  354.     
  355.         CALL_WIDTH    = max(CALL_WIDTH,    1 + l2s(buf, tot_calls));
  356.         OWN_WIDTH    = max(OWN_WIDTH,    1 + l2s(buf, ticks2msec(tot_times)));
  357.         INNER_WIDTH    = max(INNER_WIDTH,    1 + l2s(buf, ticks2msec(tot_2times)));
  358.     
  359.     #endif
  360. }
  361.  
  362. /*
  363.     Print wildcard table.
  364. */
  365. void
  366. sl_dump_wild(void)
  367. {
  368.     register sl_node    * p;
  369.  
  370.     ecnls(2);
  371.     epads("Wildcards", 20); es("   tracing");
  372.  
  373.     for (p = sl_wcard; p; p = p -> next) {
  374.         enl();
  375.         epads(p -> name, 20);
  376.         eblanks(6);
  377.         ebool(p -> trace);
  378.     }
  379.     enl();
  380. }
  381.  
  382. /*
  383.     Print the subtotals.
  384. */
  385. void
  386. sl_dump_subtotals(void)
  387. {
  388.     ecnl();
  389.     epads("SUB TOTALS", TRACEPOINT_WIDTH);
  390.     sl_dump_col(CALL_WIDTH,  subtot_calls,  subtotp_calls,  1000, " ", FALSE);
  391.     sl_dump_col(OWN_WIDTH,   subtot_times,  subtotp_times,  1000, " ", TRUE);
  392.     sl_dump_col(INNER_WIDTH, subtot_2times, subtotp_2times, 1000, " ", TRUE);
  393.     ecnls(2);
  394. }
  395.  
  396. void
  397. sl_dump_subtotal_start(void)
  398. {
  399.     subtot_calls = 0;
  400.     subtotp_calls = 0;
  401.     subtot_times = 0;
  402.     subtotp_times = 0;
  403.     subtot_2times = 0;
  404.     subtotp_2times = 0;
  405. }
  406.  
  407. /*
  408.     Print the totals.
  409. */
  410. void
  411. sl_dump_totals(void)
  412. {
  413.     ecnl();
  414.     epads("TOTALS:", TRACEPOINT_WIDTH);
  415.     sl_dump_col(CALL_WIDTH,  runtot_calls,  totp_calls,  1000, " ", FALSE);
  416.     sl_dump_col(OWN_WIDTH,   runtot_times,  totp_times,  1000, " ", TRUE);
  417.     sl_dump_col(INNER_WIDTH, runtot_2times, totp_2times, 1000, " ", TRUE);
  418.  
  419.     ecnls(2);
  420.     es("Sherlock nodes: "); eint(sl_node_count);
  421.     es(" SL_MAX_NODES: "); eint(SL_MAX_NODES); enl();
  422.     if (sl_neg_count > 0) {
  423.         es("Negative times: "); elong(sl_neg_count);
  424.     }
  425.  
  426. #if 0 // defined(THINK_C) // Doesn't work on PowerPc.
  427.     ecnl();
  428.     es("maximum stack size: "); elong(sl_margin_start - sl_min_margin);
  429.     es(" minimum stack margin: "); elong(sl_min_margin); enl();
  430. #endif
  431.  
  432.     #if 1 /* This forces the whole sprintf logic to be linked in. */
  433.         if (sl_use_adjust_flag) {
  434.             es("Times adjusted by "); edouble(sl_adjval); es(" (ticks/call)"); enl();
  435.         }
  436.     #endif
  437.  
  438.     ecnl();
  439. }
  440.  
  441. /*
  442.     Print a report of the usage of the bins.
  443. */
  444. void
  445. sl_hdump(void)
  446. {
  447.     register int        i;
  448.     register int        bucket_count;
  449.     register sl_node    *p;
  450.     long bin [10];
  451.  
  452.     /* Be very careful. */
  453.     if (sl_htab == NULL) {
  454.         return;
  455.     }
  456.  
  457.     for (i = 0; i < 10; i++) {
  458.         bin[i] = 0;
  459.     }
  460.  
  461.     /* Scan all buckets. */
  462.     for (i = 0; i < SL_MAX_HASH; i++) {
  463.  
  464.         bucket_count = 0;
  465.  
  466.         for (p = sl_htab[i]; p; p = p -> next) {
  467.             bucket_count++;
  468.         }
  469.  
  470.         if (bucket_count >= 9) {
  471.             bin[9]++;
  472.         }
  473.         else {
  474.             bin[bucket_count]++;
  475.         }
  476.     }
  477.  
  478.     es("\nHash statistics\n\n");
  479.  
  480.     for (i = 0; i < 10; i++) {
  481.         es("bin["); eint(i);
  482.         es("] = "); elong(bin[i]); enl();
  483.     }
  484.     enl();
  485. }
  486.  
  487. /*
  488.     Dump the call stack.
  489.     Very useful for debugging.
  490. */
  491. void
  492. sl_dumpstk(void)
  493. {
  494.     register int         i;
  495.     register sl_snode    * sp;
  496.     register sl_node    * np;
  497.  
  498.     /* Make sure there *is* a call stack. */
  499.     if (sl_stack == NULL) {
  500.         return;
  501.     }
  502.  
  503.     ecnls(2); es("Dump of call stack:");
  504.  
  505.     for (i = 0; i < sl_level; i++) {
  506.  
  507.         ecnl();
  508.         sp = &sl_stack[i];
  509.         np = sp -> node;
  510.  
  511.         es("name: ");     epads(np -> name, 20);
  512.         es(" stat: ");  epadlong(np -> calls, 4);
  513.         es(" time: ");  epadlong(np -> time,  4);
  514.         es(" time2: "); epadlong(np -> time2, 4);
  515.         enl();
  516.     }
  517.  
  518.     ecnls(2); es("Dump of recent call stack:");
  519.  
  520.     for (i = sl_level; i < sl_lmax; i++) {
  521.  
  522.         sp = &sl_stack[i];
  523.         np = sp -> node;
  524.  
  525.         ecnl();
  526.         es("name: ");    epads(np -> name, 20);
  527.         es(" calls: "); epadlong(np -> calls, 4);
  528.         es(" time: ");  epadlong(np -> time,  4);
  529.         es(" time2: "); epadlong(np -> time2, 4);
  530.         enl();
  531.     }
  532.     ecnl();
  533. }
  534.  
  535. /*
  536.     Set sl_adjval to the "asymptotic" Sherlock overhead.
  537.  
  538.     This overhead does *not* include the time spent searching for the
  539.     tracepoint the first time the macro is encountered.
  540.  
  541.     The value of sl_adjval does not affect how statistics are gathered,
  542.     only how the routines in this file report the statistics already gathered.
  543. */
  544.  
  545. static void dummy(int i);
  546.  
  547. /* Make sure the STAT macro are always defined. */
  548. #define STAT2(a)    {static sl_node *sl_h_=0; sl2stat(&sl_h_,a);}
  549. #define STATB2(a)    {static sl_node *sl_h_=0; sl2bstat(&sl_h_,a);}
  550. #define STATX2(a)    {sl_xtrace(a);}
  551.  
  552. void
  553. sl_setadj(void)
  554. {
  555.     unsigned long start;
  556.     unsigned long val1;
  557.     unsigned long val2;
  558.     register int i;
  559.     double d1000;
  560.     double dval;
  561.  
  562.     /* Get value with no Sherlock overhead. */
  563.  
  564.     start = sl_ticks();
  565.     for (i = 0; i < 1000; i++) {
  566.         dummy(i);
  567.     }
  568.     val1 = sl_ticks() - start;
  569.  
  570.     /*
  571.         We will perform this loop 1000 times so that we can
  572.         get a better value for the average value of the overhead.
  573.         (The constant 1000 appears in the calculation below.)
  574.  
  575.         A key point:  the sl_adjval is used to subtract a "fudge"
  576.         factor from timing statistics based on the "calls" statistic.
  577.         But only the STATB macro increments the "calls" statistics,
  578.         so we have to have *both* a STATB and a STATX macro in the following
  579.         loop to get a proper estimate of the Sherlock overhead.
  580.     */
  581.     
  582.     #ifdef SL_USE_MICROSECONDS
  583.     {
  584.         UnsignedWide wide_time;
  585.         Microseconds(&wide_time);
  586.         start = wide_time.lo;
  587.     }
  588.     #else
  589.         start = sl_ticks();
  590.     #endif
  591.     
  592.     for (i = 0; i < 1000; i++) {
  593.         STATB2("sl_setadj");
  594.         dummy(i);
  595.         STATX2("sl_setadj");
  596.     }
  597.  
  598.     
  599.     #ifdef SL_USE_MICROSECONDS
  600.     {
  601.         UnsignedWide wide_time;
  602.         Microseconds(&wide_time);
  603.         val2 = wide_time.lo - start;
  604.     }
  605.     #else
  606.             val2 = sl_ticks() - start;
  607.     #endif
  608.  
  609.     dval = val2 - val1;
  610.     d1000 = (double) 1000;
  611.     sl_adjval = (dval / d1000);
  612.     if (sl_adjval < 0.0) {
  613.         sl_adjval = 1.0;
  614.     }
  615.     
  616.     // Clear the statistics for sl_set_adj
  617.     {
  618.         sl_node * sp = sl_find("sl_setadj", "sl_setadj");
  619.         sp -> calls = 0;
  620.         sp -> time = 0;
  621.         sp -> time2 = 0;
  622.     }
  623. }
  624.  
  625. /*
  626.     A do-nothing routine that may prevent some unwanted loop optimizations.
  627.     The speed of this routine should not affect the value of TIME_ADJUST.
  628. */
  629. static int global_var;
  630.  
  631. static void
  632. dummy(int i)
  633. {
  634.     global_var += i;
  635. }
  636.  
  637. /*
  638.     l2s(buf, val); is the same as sprintf(buf, "%ld", val);
  639.     We define l2s to avoid pulling in the whole floating point library.
  640. */
  641. static short
  642. l2s (char * buf, long val)
  643. {
  644.     short length = 0;
  645.     
  646.     if (val < 0) {
  647.         buf[length++] = '-';
  648.         val = -val;                /* A small bug: this can cause overflow. */
  649.     }
  650.     
  651.     /* Generate the digits in reverse order. */
  652.     do {
  653.         buf[length++] = (val % 10) + '0';
  654.         val /= 10;
  655.     }
  656.     while (val > 0);
  657.     
  658.     /* Reverse the digits. */
  659.     {
  660.         short i = (buf[0] == '-');
  661.         short j = length-1;
  662.         
  663.         while (i < j) {
  664.             char temp = buf[j];
  665.             buf[j] = buf[i];
  666.             buf[i] = temp;
  667.             i++; j--;
  668.         }
  669.     }
  670.     
  671.     buf[length] = '\0';
  672.     return length;
  673. }